Split per-database collection timing into open + drain — the measurement the next QS fix needs (#2164) - #2173
Conversation
A production measurement overturned this issue's premise: cutting the query_store text budget 64MB -> 12MB moved 5x fewer bytes and ~7x fewer rows while the batch clock stayed in its old band (358-480s -> 383s, 352s). So the dominant cost is upstream of shipping — but the single blended sql: number could not say WHICH statement, and the next fix (a known-hash plan skip aimed at plan-XML conversion in the FINAL select) would have been aimed at the same wrong term. ExecuteReaderAsync returns only when the first rowset is available, so timing the open separately splits the batch for free: open covers every preceding non-rowset statement — for query_store, the #pm_qs_slice aggregate — plus time-to-first-row, and the remainder is streaming. The two have different fixes, so they need to be separately visible. Zero means not measured (Lite does not measure it) and suppresses the split rather than printing open:0ms, which would read as free. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
| { | ||
| _logger?.LogInformation(" [{Server}] {Collector} [{Database}] => {Rows} rows (sql:{SqlMs}ms = open:{OpenMs}ms + drain:{DrainMs}ms, pg:{PgMs}ms)", | ||
| server.Config.DisplayName, definition.Name, item, batchCount, itemSqlMs, | ||
| context.PerItemOpenMs, Math.Max(0, itemSqlMs - context.PerItemOpenMs), itemStorageMs); |
There was a problem hiding this comment.
itemSqlMs (the sql: total this drain calc is derived from) is timed by EnumeratedCollectorDriver.RunAsync's sqlSlice, which starts before perItemWatermark is awaited, not at readItem (see lines 573-591 above). For query_store — the only enumeration collector with a per-item watermark — that callback does a real Postgres round trip (GetLastCollectedTimeForDatabaseAsync), and when the catch-up clamp or adaptive-shrink path fires, it also calls RecordQueryStoreBackfillHoleAsync, which is a read+write against the store (GetCollectorStateAsync + SaveCollectorStateAsync).
None of that time is captured by context.PerItemOpenMs (which only wraps ExecuteReaderAsync inside readItem), but it is included in itemSqlMs. So drain = itemSqlMs - PerItemOpenMs silently folds the watermark-refresh/backfill-hole store I/O into "drain," even though it's neither SQL Server open time nor row-streaming time.
Given the whole point of this instrumentation is to let a reader decide "narrow the server-side aggregate" vs. "the budget/link is the lever" from the split, a database that trips the clamp/adaptive-shrink path on every quiet cycle will look more drain-heavy than it actually is. Worth excluding the watermark callback's time from the sql: slice used here (or timing it separately) so the split stays trustworthy for the diagnosis it exists to support.
| [Fact] | ||
| public void OpenMs_IsNotResetByTheQueryStoreRead_SoTheHostsMeasurementSurvivesToTheLog() | ||
| { | ||
| /* The query_store collector resets its OWN per-item signals at the top of a read. The host sets | ||
| PerItemOpenMs before calling that read, so the collector must leave it alone — otherwise the | ||
| split would always log zero and the instrumentation would be silently dead. */ | ||
| var context = NewContext(); | ||
| context.PerItemOpenMs = 4_242; | ||
| context.PerItemTextBudgetExceeded = true; | ||
| context.PerItemTextBytesShipped = 999; | ||
|
|
||
| /* Mirrors the collector's documented reset set — deliberately enumerated rather than invoking the | ||
| read (which needs a live reader), so this test states the contract the read must honor. */ | ||
| context.PerItemTextBudgetExceeded = false; | ||
| context.PerItemTextBytesShipped = 0; | ||
| context.PerItemShippedBoundary = null; | ||
|
|
||
| Assert.Equal(4_242, context.PerItemOpenMs); | ||
| } |
There was a problem hiding this comment.
This test doesn't actually exercise QueryStoreCollector's reset code — it manually sets PerItemTextBudgetExceeded/PerItemTextBytesShipped/PerItemShippedBoundary back to their reset values itself, then asserts PerItemOpenMs is untouched. That only proves CollectorContext doesn't do anything surprising to its own field; it would not catch a regression where QueryStoreCollector.ReadRowsAsync (PerformanceMonitor.Collectors/QueryStoreCollector.cs:1096-1098) itself starts zeroing PerItemOpenMs — which is exactly the silent-zero regression the doc comment above (and this PR's description) says this test guards against.
There's already a FakeCollectorDataReader + established pattern for this in Lite.Tests/QueryStoreCollectorDefinitionTests.cs (ReadItemAsync_ResetsPerItemSignals_AndNormalRowsDoNotTripTheBudget, ~line 870), which pre-sets signals and then calls QueryStoreCollector.Instance.ReadItemAsync(...) for real. Doing the same here (pre-set PerItemOpenMs, call the real ReadItemAsync with a fake reader, assert it survives) would pin the actual contract instead of a hand-mirrored copy of it.
Same concern applies to DrainIsTheRemainder_AndNeverNegative above — it recomputes Math.Max(0, sqlMs - context.PerItemOpenMs) inline rather than calling the runner's actual log-line arithmetic, so a refactor of that line in DarlingCollectorRunner.cs could drift from this test without either one failing.
|
Reviewed. This is diagnostics-only instrumentation (open vs. drain timing) with no behavior change to collection — scope is appropriately small and the reasoning in the PR body is sound. Two left inline:
Other things checked, no issues found:
Minor/non-blocking: |
Two findings, both real: 1. The driver's per-item stopwatch starts BEFORE the watermark refresh, which for query_store is a store read (plus a store write on the clamp path) — so those milliseconds were being counted as drain, in the exact metric this instrumentation exists to make trustworthy. Measured as its own phase and reported: wm + open + drain. 2. Two of the three tests re-implemented the formula instead of calling it, so they could not have caught (1). The subtraction now lives in CollectorContext.DrainMsFrom — one definition, called by both the log line and the tests — and the pins cover watermark exclusion, the clamp under stopwatch skew, and that the parts sum to the whole. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
|
Both taken, and the second one's fix is where the first one belonged:
|
|
Reviewed both commits (initial split + the review-driven watermark fix). Checked specifically for:
One very-low-severity note, not blocking: the extended log line only fires when No correctness, security, or performance issues found. The instrumentation is purely additive to logging (no behavior change to collection, as the PR description states), and the test coverage for the clamping/degenerate cases looks solid. |
1 participant
Why this instead of the fix I said I'd build
I was queued to build #2164's second half (skip re-shipping plan XML the store already holds). Then I measured the first half on a production server and it overturned the premise:
sql:time5x less text, ~7x fewer rows, and the clock did not move. So the cost is upstream of shipping, which indicts the hash-skip too — it targets
CONVERT(nvarchar(max), qsp.query_plan)in the final select, i.e. the same term the budget already proved isn't dominant. Building it would have been a second guess dressed as a fix.The blocker to knowing more is that our own log blends the batch:
ExecuteReaderAsyncblocks through the non-rowsetSELECT … INTO #pm_qs_slice, so the aggregate and the final select are indistinguishable insql:.What this does
Times the open separately from the drain, exploiting the fact that ADO.NET returns the reader only when the first rowset is available:
#pm_qs_sliceaggregate) + the final select's time-to-first-row. Nothing client-side shortens this.The per-database line becomes
sql:Xms = open:Yms + drain:Zms. Zero means not measured (Lite doesn't) and suppresses the split rather than printingopen:0ms, which would read as "the aggregate was free". Cleared before each open so a faulted read can't log the previous item's split as its own.What it buys
After one nightly on the dogfood box, the field question becomes answerable instead of arguable: if those 350–480s passes are ~95% open, the fix is narrowing the server-side aggregate (bound its input, narrow the interval span, or run it less often on expensive servers) and no amount of payload trimming matters. If they're mostly drain, the budget knob was right and the link is the problem. Either way the next PR starts from a number.
Testing
StatementSplitTimingTestspins the contract: zero means unmeasured (so an unmeasured host is never read as instant), drain is the remainder and never negative even under clock skew between the two watches, and the query_store read's own signal resets must not clobber the host's measurement — which if broken would make the whole instrumentation silently log zero. Collectors, Service, and test projects build clean.Groundwork for #2164; no behavior change to collection itself.